Skip to content

Diagnostics: identify the double close behind the async Closer EBADF assertion on the asan lane - #38630

Draft
robobun wants to merge 8 commits into
mainfrom
farm/b42f5b38/closer-ebadf-diag
Draft

robobun wants to merge 8 commits into
mainfrom
farm/b42f5b38/closer-ebadf-diag

Conversation

@robobun

@robobun robobun commented Aug 14, 2026

Copy link
Copy Markdown
Collaborator

Diagnostics only, do not merge

The x64-asan test lane intermittently aborts a bun test --test-worker --isolate process with:

panic: assertion failed: err.is_none()
  src/sys/fd.rs:73      FdExt::close            (debug_assert: "use after close!")
  src/io/lib.rs:2246    closer::Closer::run     (async close on the work pool)
  src/threading/work_pool.rs:66

i.e. by the time the async Closer ran, the fd it was handed had already been closed by something else. The crash report does not say which fd or which object scheduled the close, and it has not reproduced locally with a debug build (the same 52-file batch passes under --isolate and --parallel=N). It reproduces on the asan lane in most builds (seen in builds 95992, 95993, 95999, 96000 x2, 96094 x2, usually attributed to the file that just finished running, e.g. test/cli/test/concurrent-test-glob.test.ts, test/js/node/events/event-emitter.test.ts, test/js/node/readline/stdin-pause-pty.test.ts).

This PR adds debug_assertions-only instrumentation (Linux) so the next occurrence names both sides of the double close:

  • bun_sys::close_ledger: every successful close issued through bun_sys records a backtrace keyed by fd number; an EBADF close prints the attempt's backtrace plus the recorded first closer.
  • Closer captures a backtrace when it is scheduled and prints it before panicking if its close comes back EBADF.

The instrumentation will be removed; the real fix goes in a separate PR once the CI output identifies the owner.

Comment thread src/sys/close_ledger.rs Outdated
Comment on lines +1 to +7
//! Debug-only (`debug_assertions`) diagnostics for double closes.
//!
//! Every successful `close(2)` issued through `bun_sys` records the calling
//! thread and a backtrace, keyed by fd number. When a later close of the same
//! number fails with `EBADF` (a use-after-close, or a second owner closing a
//! descriptor it does not own), the reporter can name the code path that
//! closed it first.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

@robobun

robobun commented Aug 14, 2026

Copy link
Copy Markdown
Collaborator Author

Status: diagnostics-only PR, not for merging. Waiting on the x64-asan lane of build 96382 to hit the Closer EBADF assertion again (it fired in builds 95992, 95993, 95999, 96000 and 96094 on unrelated branches) so the new report names the object that scheduled the async close and the code path that had already closed the fd. The instrumentation itself will not land; the fix will be opened as a separate PR, so the comment-style note above is moot.

@robobun

robobun commented Aug 14, 2026 •

Copy link
Copy Markdown
Collaborator Author
Updated 12:41 PM PT - Aug 14th, 2026

⏳ @autofix-ci[bot], your commit b334a7d is still building in Build #96482, but has 1 failures so far (All Failures):

Comment thread src/sys/close_ledger.rs Outdated
Comment on lines +1 to +8
//! Debug-only (`debug_assertions`) diagnostics for double closes.
//!
//! Every successful `close(2)` issued through `bun_sys` records the calling
//! thread and a frame-pointer stack trace, keyed by fd number. When a later
//! close of the same number fails with `EBADF` (a use-after-close, or a second
//! owner closing a descriptor it does not own), the reporter prints the code
//! path that closed it first. Traces are printed as raw return addresses
//! (symbolize them against the binary with llvm-symbolizer).

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

Comment thread src/sys/close_ledger.rs Outdated
Comment on lines +71 to +72
/// Print an EBADF report for a close attempt of `fd` made by `what`: the
/// current stack, then the stack that closed `fd` last.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

@robobun

robobun commented Aug 14, 2026

Copy link
Copy Markdown
Collaborator Author

The comment-style notes above are on the throwaway instrumentation and will go away with it; nothing in this PR is meant to land. Current state: build 96420 has the instrumented asan binary built and its 20 test shards queued. Once a shard reproduces the Closer EBADF, its log will carry the close ledger output (victim's scheduling site plus the first closer), this PR gets closed, and the fix goes up separately with a test.

Comment thread src/io/lib.rs
Comment on lines +2241 to +2242
/// What the fd pointed at when the close was scheduled (empty if it
/// was already closed by then).

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

Comment thread src/sys/close_ledger.rs
Comment on lines +1 to +9
//! Debug-only (`debug_assertions`) diagnostics for double closes.
//!
//! Every successful `close(2)` issued through `bun_sys` records the calling
//! thread, what the descriptor pointed at (`/proc/self/fd/N`), and a
//! frame-pointer stack trace, keyed by fd number (the last few closes of each
//! number are kept). When a later close of the same number fails with `EBADF`
//! (a use-after-close, or a second owner closing a descriptor it does not
//! own), the reporter prints that history. Traces are printed as raw return
//! addresses (symbolize them against the binary with llvm-symbolizer).

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

Comment thread src/sys/close_ledger.rs
Comment on lines +86 to +87
/// Record that `fd` (which pointed at `description` before the call) was just
/// closed successfully by the current thread.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

Comment thread src/sys/close_ledger.rs
Comment on lines +138 to +139
/// Print an EBADF report for a close attempt of `fd` made by `what`: the
/// current stack, then the close history of `fd`.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

Comment thread src/sys/close_ledger.rs Outdated
Comment on lines +149 to +150
/// Print the current stack plus what `fd`, stdout and stderr point at. Used to
/// report failures to register `fd` with the event loop.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

@robobun

robobun commented Aug 14, 2026

Copy link
Copy Markdown
Collaborator Author

Round 2 results (build 96420, instrumented asan binary). The bot notes above are on the throwaway instrumentation and are not being addressed.

The crash reproduced twice with the ledger active (the concurrent-test-glob worker and the event-emitter worker, same as on other branches), and both reports have the same shape:

  • The fd is 30 in every occurrence, and both closes happen on the worker's main thread inside one host function called from JS.
  • First close: FdExt::close called from runtime code at 0x7788034, reached from 0x73f3f10.
  • Second close: the async Closer, scheduled from 0x6d8ea80 <- 0x7788cf8 <- 0x73f3f6c, i.e. the same caller as the first close, 0x5c bytes later, through a routine 0xcc4 bytes after the first one in the same module, with the rest of the stack identical.

That layout matches Blob::get_writer (src/runtime/webcore/Blob.rs): FileSink::start -> setup() closes the freshly opened/dup'd fd when writer.start() fails (src/runtime/webcore/FileSink.rs, the fd.close() in the start error arm), and the FileSink::deref right after it drops the PosixStreamingWriter, whose handle was already set to PollOrFd::Poll(fd) by start() before registration failed, so Drop closes the same fd again through the Closer. Every other start() caller (subprocess stdin, the shell writer, the buffered writer) treats the writer as owning the fd after a failed start(); setup() is the one that closes it itself. In release builds the second close lands on whatever has reused the fd number by then.

Still open: why epoll_ctl rejects the registration in these workers (Bun.file(2).writer() behind process.stderr, created for every isolated file; the same fd number every time points at a stale registration for the same file, which would be a second bug). The artifact is not downloadable from here, so build 96475 carries a third round that records what each closed fd pointed at, keeps the last three closes per fd, and reports failed epoll_ctl calls with errno.

Comment thread src/sys/close_ledger.rs
Comment on lines +149 to +150
/// Event-loop registration events (epoll add/del) per fd, same shape as the
/// close ledger. `kind` is a free-form label supplied by the event loop.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

Comment thread src/sys/close_ledger.rs
Comment on lines +226 to +228
/// Print the current stack plus what `fd`, stdout and stderr point at, the
/// registration events recorded for `fd`, and its close history. Used to
/// report failures to register `fd` with the event loop.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you need a paragraph-long comment to justify why the workaround is OK, the code is wrong — fix the code

@robobun

robobun commented Aug 14, 2026

Copy link
Copy Markdown
Collaborator Author

Round 3 results (build 96482). The bot notes on the instrumentation are still not being addressed; it is all going away.

Confirmed end to end, twice (the concurrent-test-glob worker, which crashed, and the event-emitter worker, which did not):

epoll_ctl(CTL_ADD, fd 30, writable) failed: EEXIST
fd 30 is "socket:[100533]"; fd 2 is "socket:[100533]"
  • fd 30 is a fresh dup(2): this is Bun.file(2).writer(), i.e. the process.stderr fast path that every isolated test file creates in a worker whose stderr is a socketpair. The kernel still holds a registration for (stderr's socket, fd 30) from an earlier dup that lived at the same number, so the ADD fails.
  • FileSink::setup closes fd 30 itself on that failure (close Add table of contents and tidy up README a bit #87 in the ledger, main thread, from the same host call), and the writer it belongs to still holds the fd in its PollOrFd::Poll handle, so releasing the sink closes it again through the async Closer: that is the err.is_none() assertion.
  • In the event-emitter worker the same EEXIST happened but nothing crashed: something else had already been opened at fd 30 by the time the Closer ran, so the second close silently closed that unrelated descriptor. That is what this bug does in release builds.

The fix for the crash is in FileSink::setup (release the fd through the writer's handle instead of closing it behind the writer's back); PR with a test to follow on a separate branch. The remaining question is which earlier registration of (stderr, 30) was never removed; build 96535 records every epoll ADD/DEL and handle close per fd and prints them at the EEXIST, which should name it.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant